Add system table section along with profile events debugging#187
Add system table section along with profile events debugging#187VighneshPath wants to merge 1 commit into
Conversation
|
All contributors have signed the CLA ✍️ ✅ |
|
I have read the CLA Document and I hereby sign the CLA |
|
recheck |
e49fab6 to
2754e61
Compare
| - clickhouse query performance | ||
| --- | ||
|
|
||
| [`system.query_log`](https://clickhouse.com/docs/en/operations/system-tables/query_log) stores metadata and statistics about executed queries — start time, duration, error messages, resource usage, and other execution details. Its `ProfileEvents` column is where the per-query counters live, and it is the first place to look when a query is slower than expected. |
There was a problem hiding this comment.
The most basic are duration and read_rows / read_bytes: usually enough to see queries where filtering does not work good.
Grouping by normalized query hash / initial_user / tables/ etc - is a common pattern.
For distributed - clusterAllReplicas query_log where initial_query_id = .... ordered by query_start_time_ms allow to see all the subqueries triggered by a single one (it can be very valuable).
|
|
||
| Reading by `ValueType` is the trick that keeps the analysis honest: a `Bytes` counter tells you *how much data* moved, a `Microseconds` counter tells you *where the time went*, and you compare like with like. The most important accumulator is: | ||
|
|
||
| - **`RealTimeMicroseconds`** — total wall-clock time spent in processing threads. It is a **sum across threads**, so it can be much larger than the query's actual duration; every other `Microseconds` counter is a slice of it. |
There was a problem hiding this comment.
Simple napkin math : divide it by click time to get how many cores were working
| ```json | ||
| { | ||
| "RealTimeMicroseconds": 9385304, | ||
| "OSCPUVirtualTimeMicroseconds": 2726569, |
There was a problem hiding this comment.
This one is one if the most important = how long cpu core were really working on that query (it's roughly the sum of user time and system time).
| "UserTimeMicroseconds": 2604127, | ||
| "S3HeadObjectMicroseconds": 1022111, | ||
| "S3ReadMicroseconds": 1013884, | ||
| "OSCPUWaitMicroseconds": 925966, |
There was a problem hiding this comment.
This one can be the sign of cpu starvation. Especially if it is a significant % of cpu virtual time.
Similarly IOwait - is the clear sign of IO starvation
| - Time in HEAD/GET requests to S3 (residual metadata only) → ~1 s | ||
| - Time a thread was ready to run but waiting → ~0.9 s | ||
| - Disk read from the cache → 65 ms | ||
| - Wait for Parquet reads from decoding threads → 62 ms |
There was a problem hiding this comment.
Networkread / write microseconds can be very confusing sometimes. They just show how long one node was vaition for other to respond to subquery (it is not a network issue).
2 participants
No description provided.